Profiling

Profiling with python command line


In [15]:
%%writefile my_code.py
from time import sleep

def stupid_func(a):
    """
    Stupid function that sleep for 0.01sec and return the parameter squared
    
    Parameter
    ---------
    a      float
           a number you want to square
           
    Returns
    -------
    b      float
           b = a**2
        
    Example
    -------
    >>> stupid_func(2.)
    4.0
    
    """
    sleep(0.01)
    return a**2.

def run_100_times():
    """Runs that stupid_func 100 times"""
    for i in range(100):
        stupid_func(i)
        
if __name__ == "__main__":
    run_100_times()


Overwriting my_code.py

In [2]:
!python -m cProfile -s time my_code.py


         204 function calls in 1.055 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      100    1.051    0.011    1.051    0.011 {time.sleep}
        1    0.002    0.002    1.055    1.055 my_code.py:1(<module>)
      100    0.001    0.000    1.052    0.011 my_code.py:3(stupid_func)
        1    0.001    0.001    1.053    1.053 my_code.py:26(run_100_times)
        1    0.000    0.000    0.000    0.000 {range}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}


Note that the cumulated time of the program should be 100*0.01 = 1.0 sec, because of the overhead of python (and especially the profiler) it's a bit longer. Note that the function my_code.py:3(stupid_func) is run 100 times.

Profiling within a script


In [13]:
import cProfile, pstats, StringIO
from my_code import run_100_times

pr = cProfile.Profile()
pr.enable()

run_100_times()  

pr.disable()
s = StringIO.StringIO()
ps = pstats.Stats(pr, stream=s).sort_stats('tottime')
ps.print_stats()
print s.getvalue()


         219 function calls in 1.055 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      100    1.053    0.011    1.053    0.011 {time.sleep}
      100    0.001    0.000    1.054    0.011 my_code.py:3(stupid_func)
        1    0.001    0.001    1.055    1.055 my_code.py:26(run_100_times)
        2    0.000    0.000    0.000    0.000 {compile}
        2    0.000    0.000    1.055    0.528 /Users/pire/venv/openmdao/lib/python2.7/site-packages/IPython/core/interactiveshell.py:2854(run_code)
        2    0.000    0.000    0.000    0.000 /opt/local/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/codeop.py:132(__call__)
        2    0.000    0.000    0.000    0.000 /Users/pire/venv/openmdao/lib/python2.7/site-packages/IPython/core/hooks.py:127(__call__)
        2    0.000    0.000    0.000    0.000 /Users/pire/venv/openmdao/lib/python2.7/site-packages/IPython/utils/ipstruct.py:125(__getattr__)
        1    0.000    0.000    1.055    1.055 <ipython-input-13-39b01f33649a>:7(<module>)
        1    0.000    0.000    0.000    0.000 <ipython-input-13-39b01f33649a>:9(<module>)
        1    0.000    0.000    0.000    0.000 {range}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        2    0.000    0.000    0.000    0.000 /Users/pire/venv/openmdao/lib/python2.7/site-packages/IPython/core/interactiveshell.py:1055(user_global_ns)
        2    0.000    0.000    0.000    0.000 /Users/pire/venv/openmdao/lib/python2.7/site-packages/IPython/core/hooks.py:192(pre_run_code_hook)



Profiling in ipython

You just need to use the magic line function %prun or cell function %%prun


In [8]:
%prun run_100_times()


 

In [9]:
%%prun
for i in range(100):
    stupid_func(i)


 

In [10]:
%prun %run my_code.py


 

Reference material:


In [ ]: